读懂Young GC日志

发表于 | 分类于

文章摘要

在进行JVM调优时我们经常需要通过日志信息来分析G1GC的性能，本文就日志中可供收集的数据和信息进行了简单介绍。

Young GC日志

下面选取了SZVPC线上报价服务的一段Young GC日志：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
{Heap before GC invocations=38623 (full 4):
 garbage-first heap   total 25165824K, used 11321508K [0x00000001c0000000, 0x00000001c040c000, 0x00000007c0000000)
  region size 4096K, 307 young (1257472K), 26 survivors (106496K)
 Metaspace       used 23093K, capacity 23236K, committed 29440K, reserved 1075200K
  class space    used 2444K, capacity 2510K, committed 3328K, reserved 1048576K
2018-12-18T11:19:27.084+0800: 671040.790: [GC pause (G1 Evacuation Pause) (young), 0.3639131 secs]
   [Parallel Time: 354.4 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 671040790.4, Avg: 671040790.6, Max: 671040790.8, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.8, Avg: 1.0, Max: 1.2, Diff: 0.4, Sum: 13.0]
      [Update RS (ms): Min: 22.6, Avg: 23.0, Max: 23.6, Diff: 1.0, Sum: 299.6]
         [Processed Buffers: Min: 24, Avg: 32.5, Max: 39, Diff: 15, Sum: 422]
      [Scan RS (ms): Min: 201.4, Avg: 202.0, Max: 202.4, Diff: 1.0, Sum: 2625.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [Object Copy (ms): Min: 126.9, Avg: 127.2, Max: 127.8, Diff: 0.9, Sum: 1653.5]
      [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.9, Diff: 0.9, Sum: 8.3]
         [Termination Attempts: Min: 1, Avg: 278.6, Max: 349, Diff: 348, Sum: 3622]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 1.6]
      [GC Worker Total (ms): Min: 353.8, Avg: 354.0, Max: 354.2, Diff: 0.4, Sum: 4602.1]
      [GC Worker End (ms): Min: 671041144.5, Avg: 671041144.6, Max: 671041144.7, Diff: 0.2]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 1.7 ms]
   [Other: 7.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 2.5 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 3.0 ms]
   [Eden: 1124.0M(1124.0M)->0.0B(1132.0M) Survivors: 104.0M->96.0M Heap: 10.8G(24.0G)->9968.2M(24.0G)]
Heap after GC invocations=38624 (full 4):
 garbage-first heap   total 25165824K, used 10207396K [0x00000001c0000000, 0x00000001c040c000, 0x00000007c0000000)
  region size 4096K, 24 young (98304K), 24 survivors (98304K)
 Metaspace       used 23093K, capacity 23236K, committed 29440K, reserved 1075200K
  class space    used 2444K, capacity 2510K, committed 3328K, reserved 1048576K
}
 [Times: user=4.64 sys=0.00, real=0.36 secs]

日志信息详解：

  • garbage-first heap total 25165824K, used 11321508K [0x00000001c0000000, 0x00000001c040c000, 0x00000007c0000000)

    可以看出GC的类型为G1，Heap的总大小为25165824K，已使用11321508K。

  • region size 4096K, 307 young (1257472K), 26 survivors (106496K)

    每个region的大小为4096K，新生代307个region，survivor区26个region。

  • Metaspace used 23093K, capacity 23236K, committed 29440K, reserved 1075200K
    class space used 2444K, capacity 2510K, committed 3328K, reserved 1048576K

    java8去掉了永久区（Permanent），新增元数据区（Metaspace）。

  • 671040.790: [GC pause (G1 Evacuation Pause) (young), 0.3639131 secs]

    G1停顿清理(young) regions，即新生代minor GC。本次停顿在JVM启动后671040.790 s后触发，且停顿持续时间为0.3639131 s，根据系统时间（wall clock time）测定。

  • [Parallel Time: 354.4 ms, GC Workers: 13]

    收集过程是多线程并发执行的，日志表明在354.4ms（real time）时间内，下面的活动是由13个线程并行完成的：

    1. GC Worker Start (ms)

      收集线程开始的时间，匹配停顿开始时的时间戳。使用的是相对时间，Min是最早开始时间，Avg是平均开始时间，Max是最晚开始时间，Diff是Max-Min。 如果Min和Max差别很大，那么可能表明使用了太多线程或者机器上的其他进程正在从JVM内部的垃圾收集进程中窃取CPU时间。

    2. Ext Root Scanning (ms)

      扫描外部（非heap）roots如类加载器、JNI引用、JVM 系统roots等的耗时，Sum是Cpu time。

    3. Update RS (ms)

      每个线程更新Remembered Set的耗时。

    4. Scan RS (ms)

      扫描CS中的region对应的RSet，因为RSet是points-into，所以这样实现避免了扫描old generadion region，但是会产生float garbage。

    5. Code Root Scanning (ms)

      扫描code roots如本地变量的耗时。code roots指的是经过JIT编译后的代码里，引用了heap中的对象。引用关系保存在RSet中。

    6. Object Copy (ms)

      从收集region拷贝存活的对象到新region的耗时。

    7. Termination (ms)

      工作线程确保它们能够安全地停止并且没有更多的工作要做最终终止所用的耗时。在结束前，它会检查其他线程是否还有未扫描完的引用，如果有，则”偷”过来，完成后再申请结束，这个时间是线程之前互相同步所花费的时间。

      • Termination Attempts

        工作线程尝试终止的次数，如果实际还有更多的工作要做，那么尝试就会失败，现在终止还为时过早。

    8. GC Worker Other (ms)

      花费在其他杂项（不值得在日志中单独占用一个部分）上的时间。

    9. GC Worker Total (ms)

      所用工作线程耗时之和。

    10. GC Worker End (ms)

      每个线程结束的时间戳，通常它们应该大致相等。

  • [Code Root Fixup: 0.0 ms]

    用来将code root修正到正确的evacuate之后的对象位置所花费的时间。

  • [Code Root Purge: 0.0 ms]

    清除code root的耗时，code root中的引用已经失效，不再指向Region中的对象，所以需要被清除。

  • [Clear CT: 1.7 ms]

    清除RSet的card table的耗时，这个任务在serial模式下执行。

  • [Other: 7.8 ms]

    下面所列的其他事项共耗时7.8ms：

    1. [Choose CSet: 0.0 ms]

      查找Collection Set的region的耗时；

    2. [Ref Proc: 0.6 ms]

      Reference Process， 处理引用对象的耗时；

    3. [Ref Enq: 0.0 ms]

      Reference enqueue，引用对象排队到引用队列的耗时；

    4. [Redirty Cards: 2.5 ms]略

    5. [Humongous Register: 0.2 ms]略

    6. [Humongous Reclaim: 0.1 ms]略

    7. [Free CSet: 3.0 ms]

      清理Collection Set数据结构的耗时；

  • [Eden: 1124.0M(1124.0M)->0.0B(1132.0M) Survivors: 104.0M->96.0M Heap: 10.8G(24.0G)->9968.2M(24.0G)]

    分别代表：停顿前后Eden区已用内存和容量；停顿前后Survivor区使用的内存；停顿前后整个Heap已用内存和容量。

  • [Times: user=4.64 sys=0.00, real=0.36 secs]

    整个GC事件的持续时间，从以下不同的类别来测量：

    1. user - 本次垃圾收集中GC线程所消耗的总体CPU时间；

    2. sys - OS调用或等待系统事件的耗时；

    3. real - 应用程序停止的时间（Clock time）。在GC活动可并行执行的情况下，这个数值理想上应为：（user时间 + sys时间）/ GC所用的线程数，在这个case里线程数是13。要注意的是，有些活动不能并行执行，因此该数值总会超过这个比例一定数量。

参考文献

Getting Started with the G1 Garbage Collector

Understanding G1 GC Logs

JAVA GARBAGE COLLECTION HANDBOOK